{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "“日志(logging)”有两个意思：\n",
    "\n",
    "- 诊断日志(diagnostic log)即log4j、logback、slf4j、glog、g2log、log4cxx、log4cpp、log4cplus、Pantheios、ezlogger等常用日志库提供的日志功能。\n",
    "- 交易日志(transaction log)即数据库的[write-ahead log](https://en.wikipedia.org/wiki/Write-ahead_logging)、文件系统的[jour-naling](https://en.wikipedia.org/wiki/Journaling_file_system)等，用于记录状态变更，通过回放日志可以逐步恢复每一次修改之后的状态。\n",
    "\n",
    "本章的“日志”是前一个意思，即文本的、供人阅读的日志，通常用于故障诊断和[追踪(trace)](https://en.wikipedia.org/wiki/Traceability)，也可用于性能分析。日志通常是分布式系统中事故调查时的唯一线索，用来追寻蛛丝马迹，查出元凶。\n",
    "\n",
    "在服务端编程中，日志是必不可少的，在生产环境中应该做到[“Log Everything All The Time”](http://highscalability.com/log-everything-all-time)。对于关键进程，日志通常要记录\n",
    "1. 收到的每条内部消息的id（还可以包括关键字段、长度、hash等）；\n",
    "2. 收到的每条外部消息的全文\n",
    "> 第2、3两条或许不适用于分布式存储系统的 bulk data，但适用于meta data。\n",
    "3. 发出的每条消息的全文，每条消息都有全局唯一的id\n",
    "> 可用S9.4的办法生成。\n",
    "4. 关键内部状态的变更，等等。\n",
    "\n",
    "\n",
    "每条日志都有时间戳，这样就能完整追踪分布式系统中一个事件的来龙去脉。也只有这样才能查清楚发生故障时究竟发生了什么，比如业务处理流程卡在了哪一步。\n",
    "\n",
    "诊断日志不光是给程序员看的，更多的时候是给运维人员看的，因此日志的内容应避免造成误解，不要误导调查故障的主攻方向，拖延故障解决的时间。\n",
    "\n",
    "一个日志库大体可分为[前端(frontend)](../muduo/base/Logging.h)和[后端(backend)](../muduo/base/Logging.h)两部分。前端是供应用程序使用的接口(API)，并生成日志消息(log message)；后端则负责把日志消息写到目的地(destination)。\n",
    "\n",
    "这两部分的接口有可能简单到只有一个回调函数：`void output(const char＊message，int len)；`\n",
    "\n",
    "其中的`message`字符串是一条完整的日志消息，包含日志级别、时间戳、源文件位置、线程id等基本字段，以及程序输出的具体消息内容。\n",
    "\n",
    "在多线程程序中，前端和后端都与单线程程序无甚区别，无非是每个线程有自己的前端，整个程序共用一个后端。但难点在于将日志数据从多个前端高效地传输到[后端](../muduo/base/AsyncLogging.h)。这是一个典型的多生产者-单消费者问题，对生产者（前端）而言，要尽量做到低延迟、低CPU开销、无阻塞；对消费者（后端）而言，要做到足够大的吞吐量，并占用较少资源。\n",
    "\n",
    "对C++程序而言，最好整个程序（包括主程序和程序库）都使用相同的日志库，程序有一个整体的日志输出，而不要各个组件有各自的日志输出。从这个意义上讲，日志库是个singleton。\n",
    "\n",
    "\n",
    "C++日志库的前端大体上有两种API风格：\n",
    "- C/Java的`printf(fmt，...)`风格，例如`log_info(\"Received%d bytes from%s\", len, getClientName().c_str());`\n",
    "- C++的`stream<<`风格，例如`LOG_INFO << \"Received \" << len << \"bytes from \" << getClientName();`\n",
    "\n",
    "\n",
    "muduo日志库是C++ stream风格，这样用起来更自然，不必费心保持格式字符串与参数类型的一致性，可以随用随写，而且是类型安全的。\n",
    "> `printf(fmt，...)`风格在C++中也可以做到类型安全，但是在C++11引入variadic template之前很费劲。因为C++不允许把 non-POD对象通过可变参数`(...)`传入函数。[Pantheios](http://www.pantheios.org )日志库用的是重载函数模板的办法\n",
    "\n",
    "stream 风格的另一个好处是当输出的日志级别高于语句的日志级别时，打印日志是个空操作，运行时开销接近零。比方说当日志级别为 `WARNING` 时，`LOG_INFO <<`是[空操作](http://www.drdobbs.com/cpp/201804215)，这个语句根本不会调用 `std::string getClientName()`函数，减小了开销。而 `printf` 风格不易做到这一点。\n",
    "\n",
    "muduo没有用标准库中的`iostream，`而是自己写的[`LogStream class`](../muduo/base/LogStream.h)，这主要是出于性能原因(§ 11.6.6)。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "AI: 空操作的意思：\n",
    "- 当当前全局日志级别高于某条日志语句的级别时，这条日志语句在运行时被完全跳过，不产生任何可观察的副作用。\n",
    "- 不会构造/格式化字符串、不会分配内存、不会执行拼接，也不会调用右侧表达式中的函数（例如 `getClientName()`）。\n",
    "- 仅有一次非常便宜的级别判断分支开销，接近零成本。Pantheios将其描述为“you only pay for what you use”，并在关闭某级别日志时对性能的影响“unmeasurably low”。"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "vscode": {
     "languageId": "cpp"
    }
   },
   "outputs": [],
   "source": [
    "// 当日志级别为 WARN 时，INFO 日志为“空操作”，getClientName() 不会被调用；把级别切到 INFO 后才会调用\n",
    "\n",
    "#include <iostream>\n",
    "#include <sstream>\n",
    "#include <string>\n",
    "#include <cstdio>\n",
    "\n",
    "class Logger {\n",
    "public:\n",
    "    enum Level { kTrace, kDebug, kInfo, kWarn, kError, kFatal };\n",
    "\n",
    "    static void setLevel(Level l) { g_level() = l; }\n",
    "    static bool enabled(Level l) { return l >= g_level(); }\n",
    "\n",
    "    explicit Logger(Level l) : level_(l) {}\n",
    "    ~Logger() {\n",
    "        if (enabled(level_)) {\n",
    "            std::cout << oss_.str() << std::endl;\n",
    "        }\n",
    "    }\n",
    "\n",
    "    std::ostringstream& stream() { return oss_; }\n",
    "\n",
    "private:\n",
    "    Level level_;\n",
    "    std::ostringstream oss_;\n",
    "\n",
    "    static Level& g_level() {\n",
    "        static Level lvl = kInfo; // 默认级别\n",
    "        return lvl;\n",
    "    }\n",
    "};"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "metadata": {
    "vscode": {
     "languageId": "cpp"
    }
   },
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Level=WARN\n",
      "----\n",
      "Level=INFO\n",
      "client=Alice\n"
     ]
    }
   ],
   "source": [
    "// 当级别不满足时，整个日志表达式（含右侧函数调用）都不会执行\n",
    "#define LOG(level) if (!Logger::enabled(level)) ; else Logger(level).stream()\n",
    "\n",
    "std::string getClientName() {\n",
    "    std::puts(\"getClientName() called\"); // 用于观察是否被调用\n",
    "    return \"Alice\";\n",
    "}\n",
    "\n",
    "{\n",
    "    using L = Logger;\n",
    "\n",
    "    // 场景1：INFO 为“空操作”\n",
    "    L::setLevel(L::kWarn);\n",
    "    std::cout << \"Level=WARN\" << std::endl;\n",
    "    LOG(L::kInfo) << \"client=\" << getClientName(); // 不会调用 getClientName()\n",
    "\n",
    "    std::cout << \"----\" << std::endl;\n",
    "\n",
    "    // 场景2：INFO 生效\n",
    "    L::setLevel(L::kInfo);\n",
    "    std::cout << \"Level=INFO\" << std::endl;\n",
    "    LOG(L::kInfo) << \"client=\" << getClientName(); // 会调用并输出\n",
    "}"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# 5.1 功能需求\n",
    "\n",
    "常规的通用日志库如[log4j](https://logging.apache.org/log4j/1.x/manual.html)/[logback](https://logback.qos.ch/manual/index.html)通常会提供丰富的功能，但这些功能不一定全都是必需的。\n",
    "\n",
    "1. 日志消息有多种级别(level)，如`TRACE、DEBUG、INFO、WARN、ERROR、FATAL`等。\n",
    "2. 日志消息可能有多个目的地(appender)，如文件、socket、SMTP等。\n",
    "3. 日志消息的格式可配置(layout)，例如`org.apache.log4j.PatternLayout`。\n",
    "4. 可以设置运行时过滤器(filter)，控制不同组件的日志消息的级别和目的地。\n",
    "\n",
    "在上面这几项中，我认为除了第一项之外，其余三项都是非必需的功能。\n",
    "\n",
    "\n",
    "日志的输出级别在运行时可调，这样同一个可执行文件可以分别在QA测试环境的时候输出`DEBUG`级别的日志，在生产环境输出`INFO`级别的日志。在必要的时候也可以临时在线调整日志的输出级别。例如某台机器的消息量过大、日志文件太多、磁盘空间紧张，那么可以临时调整为`WARNING`级别输出，减少日志数目。又比如某个新上线的进程的行为略显古怪，则可以临时调整为DEBUG级别输出，打印更细节的日志消息以便分析查错。调整日志的输出级别不需要重新编译，也不需要重启进程，只要调用`muduo::Logger::setLogLevel()`就能即时生效。\n",
    "muduo 默认输出`INFO`级别的日志，可以通过环境变量控制输出 `DEBUG`或 `TRACE` 级别的日志。\n",
    "\n",
    "对于分布式系统中的服务进程而言，日志的目的地（destination）只有一个∶本地文件。\n",
    "往网络写日志消息是不靠谱的，因为诊断日志的功能之一正是诊断网络故障，比如连接断开（网卡或交换机故障）、网络暂时不通（若干秒之内没有收到心跳消息）、网络拥塞（消息延迟明显加大）等等。如果日志消息也是通过网络发到另一台机器上的，那岂不是一损俱损?如果接收网络日志消息的服务器（日志服务器）发生故障或者出现进程死锁（阻塞），通常会导致发送日志的多个服务进程阻塞，或者内存暴涨（用户态和内核的TCP缓存），这无异于放大了单机故障。往网络写日志消息的另一个坏处是增加网络带宽消耗。试想收到一条业务消息、发出一条业务消息时都会写日志，如果写到网络上岂不是让网络带宽消耗翻倍，加剧 trashing?同理，应该避免往网络文件系统（例如 NFS）上写日志，这等于掩耳盗铃。\n",
    "\n",
    "以本地文件为日志的destination，那么日志文件的滚动(rolling)是必需的，这样可以简化日志归档(archive)的实现。rolling的条件通常有两个：文件大小（例如每写满1GB就换下一个文件）和时间（例如每天零点新建一个日志文件，不论前一个文件有没有写满）。muduo日志库的`LogFile`会自动根据文件大小和时间来主动滚动日志文件。既然能主动rolling，自然也就不必支持`SIGUSR1`了，毕竟多线程程序处理signal很麻烦(§ 4.10)。\n",
    "\n",
    "一个典型的日志文件的文件名如下：\n",
    "\n",
    "```text\n",
    "logfile_test.2012060-144022.hostname.3605.log\n",
    "```\n",
    "\n",
    "文件名由以下几部分组成：\n",
    "\n",
    "- 第1部分 `logfile_test` 是进程的名字。通常是 `main()` 函数参数中 `argv[0] `的 `basename(3)`，这样容易区分究竟是哪个服务程序的日志。必要时还可以把程序版本加进去。\n",
    "- 第2部分是文件的创建时间（GMT 时区）。这样很容易通过文件名来选择某一时间范围内的日志，例如用通配符 *.20120603-14* 表示 2012 年 6 月 3 日下午 2 点（GMT）左右的日志文件(s)。\n",
    "- 第3部分是机器名称。这样即便把日志文件拷贝到别的机器上也能追溯其来源。\n",
    "- 第4部分是进程 id。如果一个程序一秒之内反复重启，那么每次都会生成不同的日志文件，参考 § 9.4。\n",
    "- 第5部分是统一的后缀名 .log。同样是为了便于周边配套脚本的编写。\n",
    "\n",
    "muduo 的日志库滚动没有采用文件改名的办法，即 dmesg.log 是最新日志，dmesg.log.1 是前一个日志，dmesg.log.2.gz 是更早的日志等。这种做法的一个好处是 dmesg.log 始终是最新日志，便于编写某些及时解析日志的脚本。将来可以增加一个功能，每次滚动日志文件之后立刻创建（更新）一个 symlink，logfile_test.log 始终指向当前最新的日志文件，这样达到相同的效果。\n",
    "\n",
    "日志文件压缩与归档（archive）不是日志库应有的功能，而应该交给专门的脚本去做，这样 C++ 和 Java 的服务程序也共享这套设施。如果想要更换日志压缩算法或归档策略也不必动业务程序，改改周边配套脚本就行了。磁盘空间监控也不是日志库的必备功能。有人或许曾经遇到日志文件把磁盘占满的情况，因此希望日志库能限制空间使用，例如只分配 10GB 磁盘空间，用满之后就冲掉旧日志、重复利用空间，就像循环磁带一样。不知如果如果出现程序死循环不停打印写日志的异常情况，那么往往在其头几条日志是关键，它往往在反映了引发异常（busy-loop）的原因（例如收到某条非法消息），后面都是无用的垃圾日志。如果日志库具备重复利用空间的“功能”，只会掩盖它。磁盘写入的带宽按 100MB/s 计算，写满一个 100GB 的磁盘分区需要 16 分钟，这足够监控系统报警并人工干预了（§ 9.2.1）。\n",
    "\n",
    "往文件写日志的一个常见问题是，万一程序崩溃，那么最后若干条日志在进程丢失了，因为日志库不能每条消息都 `fflush` 硬盘，更不能每条日志都 `open/close` 文件，这样性能开销太大。muduo 日志库在两个方面做了补救，一是定期（默认 3 秒）将缓冲区内的日志 `flush` 到硬盘；*其二是每条存内存缓冲区的日志消息都有 cookie（或者叫哨兵/sentry），其值为某个函数的地址，这样通过在 core dump 文件中查找 cookie 就能找到尚未写入磁盘的消息。*\n",
    "\n",
    "日志消息的格式是固定的，不需要运行时配置，这样可节省每条日志解析格式字符串的开销。我认为日志的格式在项目的整个生命周期几乎不会改变，因为我们经常会为不同目的编写 parse 日志的脚本，既要解析最近几天的日志文件，也要和几个月之前，甚至一年前的日志文件作同类数据做对比。如果在此期间日志格式变了，势必会增加很多无谓的工作量。如果真的需要调整消息格式，直接修改代码并重新编译即可。以下是 muduo 日志库的默认消息格式：\n",
    "\n",
    "```text\n",
    "日期      时间                线程   级别   正文    源文件名:行号\n",
    "20120603  08:02:46.125770Z   23261  INFO  Hello   test.cc:51\n",
    "20120603  08:02:46.126962Z   23261  WARN  World   test.cc:52\n",
    "20120603  08:02:46.126997Z   23261  ERROR Error   test.cc:53\n",
    "```\n",
    "\n",
    "日志消息格式有几个要点：\n",
    "\n",
    "- 量量每条日志占一行。这样很容易用 awk、sed、grep 等命令行工具来快速联机分析日志，例如某段时间内每秒打印日志的条数（直方图），可以运行\n",
    "\n",
    "```bash\n",
    "grep -o '^2012060308:02:.*' logfile | sort | uniq -c\n",
    "```\n",
    "\n",
    "- 时间戳精确到微秒。每条消息都通过 `gettimeofday(2) `获得当前时间，这么做不会有什么性能损失。因为在 x86-64 Linux 上，`gettimeofday(2)` 不是系统调用，不会陷入内核（可用 `strace(1)` 验证 [muduo/base/tests/Timestamp_unittest.cc](../muduo/base/tests/Timestamp_unittest.cc)）。\n",
    "- 始终使用 GMT 时区（Z）。对于跨海的分布式系统而言，可省去本地时区转换的麻烦（别忘了主要西方国家会实行夏令时），更易于追查事件的顺序。\n",
    "- 打印线程 id。便于分析多线程程序时，也可以检测死锁。这里的线程 id 是指调用 `LOG_INFO<< `的线程，线程 id 的获取见 § 4.3。\n",
    "- 打印日志级别。在查找故障的时候先看看有没有 ERROR 日志，通常可加速定位问题。\n",
    "- 打印源文件名和行号。修改 bug 的时候不至于搞错对象。\n",
    "\n",
    "每行日志的前 4 个字段的宽度是固定的，以空格分隔，便于用脚本解析。另外，应该避免在日志格式（特别是消息 id）中出现正则表达式的元字符（meta character），例如“[”和“]”等等，这样在用 `less(1)` 查看日志文件的时候查找字符串更加便捷。\n",
    "\n",
    "运行时的日志过滤器（filter）或许是有用的，例如控制不同部件（程序库）的输出日志级别，但我认为这应该到编译期去做，整个程序有一个整体的输出级别就足够好了。同时我认为一个程序同时写多个日志文件是非常罕见的需求，这可以事后留给 log archiver 来分流，不必做到日志库中。不实现 filter 自然也能减少生成每条日志的运行时开销，可以提高日志库的性能。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# 5.2 性能需求\n",
    "\n",
    "编写Linux服务端程序的时候，我们需要一个高效的日志库。只有日志库足够高效，程序员才敢在代码中输出足够多的诊断信息，减小运维难度，提升效率。高效性体现在几方面：\n",
    "\n",
    "- 每秒写几千上万条日志的时候没有明显的性能损失。\n",
    "- 能应对一个进程产生大量日志数据的场景，例如1GB/min。\n",
    "- 不阻塞正常的执行流程。\n",
    "- 在多线程程序中，不造成争用(contention)。\n",
    "\n",
    "这里列举一些具体的性能指标，考虑往普通7200rpm SATA硬盘写日志文件的情况：\n",
    "\n",
    "- 磁盘带宽约是110MB/s，日志库应该能瞬时写满这个带宽（不必持续太久）。\n",
    "- 假如每条日志消息的平均长度是110字节，这意味着1秒要写100万条日志\n",
    "\n",
    "以上是“高性能”日志库的最低指标。如果磁盘带宽更高，那么日志库的预期性能指标也会相应提高。反过来说，在磁盘带宽确定的情况下，日志库的性能只要“足够好”就行了。假如某个神奇的日志库1秒能往`/dev/null`写1000MB数据，那么到哪里去找这么快的磁盘来让程序写诊断日志呢？\n",
    "\n",
    "这些指标初看起来有些异想天开，什么程序需要1秒写100万条日志消息呢？换一个角度其实很容易想明白，如果一个程序耗尽全部CPU资源和磁盘带宽可以做到1秒写100万条日志消息，那么当只需要1秒写10万条日志的时候，立刻就能腾出90%的资源来干正事（处理业务）。相反，如果一个日志库在满负荷的情况下只能1秒写10万条日志，真正用到生产环境，恐怕就只能1秒写1万条日志才不会影响正常业务处理，这其实钳制了服务器的吞吐量。\n",
    "> 比方说一秒处理两三万条消息，每条消息写三条日志∶从哪里收到、计算结果如何、发到哪里。\n",
    "\n",
    "\n",
    "以下是muduo日志库在两台机器上的实测性能数据\n",
    "\n",
    "| 文件↓ 硬件→| E5320 消息/s | E5320 MiB/s | i5-2500 消息/s | i5-2500 MiB/s |\n",
    "|---|---:|---:|---:|---:|\n",
    "| nop | 97.1 万 | 107.6 | 242.2 万 | 256.2 |\n",
    "| /dev/null | 91.2 万 | 101.1 | 234.2 万 | 247.7 |\n",
    "| /tmp/log | 81.0 万 | 89.8 | 213.0 万 | 225.3 |\n",
    "\n",
    "\n",
    "可见muduo日志库在现在的PC上能写到每秒200万条消息，带宽足够撑满两个千兆网连接或4个SATA组成的RAID10，性能是达标的\n",
    "\n",
    "日志文件是顺序写入，是对磁盘最友好的一种负载，对IOPS要求不高。\n",
    "\n",
    "\n",
    "为了实现这样的性能指标，muduo日志库的实现有几点优化措施值得一提：\n",
    "- 时间戳字符串中的日期和时间两部分是缓存的，一秒之内的多条日志只需重新格式化微秒部分。例如p.111出现的3条日志消息中，`“20120603 08：02：46”`是复用的，每条日志只需要格式化微秒部分`(“.125770Z”)`。\n",
    "\n",
    "见 [muduo/base/logging.cc](../muduo/base/Logging.cc#L133)中的`Logger::Impl::formatTime()`函数。\n",
    "\n",
    "- 日志消息的前4个字段是定长的，因此可以避免在运行期求字符串长度（不会反复调用 `strlen`）。因为编译器认识`memcpy()`函数，对于定长的内存复制，会在编译期把它 inline 展开为高效的目标代码。\n",
    "\n",
    "\n",
    "见 [muduo/base/logging.cc](../muduo/base/Logging.cc#L70)中的 `class T` 和 `operator << (LogStream& s, T v)`。\n",
    "- 线程id是预先格式化为字符串，在输出日志消息时只需简单拷贝几个字节。见`CurrentThread::tidString()`。\n",
    "- 每行日志消息的源文件名部分采用了编译期计算来获得 `basename`，避免运行期`strrchr(3)`开销。见 `SourceFile class`，这里利用了gcc的内置函数。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# 5.3 多线程异步日志\n",
    "\n",
    "多线程程序对日志库提出了新的需求：线程安全，即多个线程可以并发写日志，两个线程的日志消息不会出现交织。线程安全不难办到，简单的办法是用一个全局 `mutex` 保护 IO，或者每个线程单独写一个日志文件，但这两种做法的高效率就堪忧了。前者会造成全部线程抢一个锁，后者有可能让业务线程阻塞在写磁盘操作上。\n",
    "> Google C++ 日志库的默认多线程实现即如此。\n",
    "\n",
    "我认为一个多线程程序的每个进程最好只写一个日志文件，这样分析日志容易，不必在多个文件中来回跳去。再说多线程写多个文件也不一定能提高速度，见 p.99-4.6 的分析。解决办法不难想到，用一个背景线程负责收集日志消息，并写入日志文件，其他业务线程只管往这个“日志线程”发送日志消息，这称为“异步日志”。\n",
    "\n",
    "在多线程服务器中，异步日志（叫“非阻塞日志”似乎更准确）是必需的，因为如果在网络 IO 线程或业务线程中直接往磁盘写数据的话，写操作偶尔可能阻塞长达数秒之久（原因很复杂，可能是磁盘或磁盘控制器复位），这可能导致请求方超时，或者导致误判，在分布式系统中更可能造成多米诺骨牌效应，例如误报服务器故障以致自动 failover 等。因此，在正常的实时业务处理流程中应该彻底避免磁盘 IO，这在使用 one loop per thread 模型的非阻塞服务器端程序中尤为重要，因为线程是稀有的，阻塞线程意味着影响多个客户端连接。\n",
    "\n",
    "我们需要一个“队列”来将日志前端的数据传送到后端（日志线程），但这个“队列”不必是现成的 `BlockingQueue<std::string>`，因为不必每次产生一条日志消息都通知（notify）接收方。\n",
    "\n",
    "muduo 日志库采用的是[*双缓冲（double buffering）技术*](http://en.wikipedia.org/wiki/Multiple_buffering)，基本思路是准备两块 buffer：A 和 B，前端负责往 `buffer A` 填数据（日志消息），后端负责将 `buffer B` 的数据写入文件。当 `buffer A` 写满之后，交换 A 和 B，让后端将 `buffer A` 的数据写入文件，而前端则往 `buffer B` 填入新的日志消息，如此往复。用两个 buffer 的好处是在新建日志消息的时候不必等待磁盘文件操作，也避免每条新日志消息都唤醒后端日志线程。换言之，前端不是将一条条日志消息分别传送给后端，而是将多条日志消息拼成一个大的 buffer 传送给后端，相当于批处理，减少了线程唤醒的频度，降低开销。另外，为了及时将日志写入文件，即便 buffer A 未满，日志库也会每 3 秒执行一次上述交换写入操作。\n",
    "\n",
    "muduo 异步日志的性能开销大约是前端每写一条日志消息耗时 1.0μs～1.6μs。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## *关键代码\n",
    "\n",
    "实际实现采用了四个缓冲区，这样可以进一步减少或避免日志前端的等待。数据结构如下([muduo/base/AsyncLogging.h](../muduo/base/AsyncLogging.h#L79))：\n",
    "\n",
    "其中，`LargeBuffer` 类型是 `FixedBuffer class template` 的一份具体实现（instantiation），其大小为 4MB，可以存至少 1000 条日志消息。`boost::ptr_vector<T>::auto_type` 类型类似 C++11 中的 `std::unique_ptr`，具备移动语义（move semantics），而且能自动管理对象生命周期。`mutex_` 用于保护后面的四个数据成员。`buffers_` 存放的是供后端写入的 `buffer`。\n",
    "\n",
    "先来看发送方代码，即p.108回调函数[`output()`](../muduo/base/AsyncLogging.cc#34)的实现。\n",
    "\n",
    "前端在生成一条日志消息的时候会调用 `AsyncLogging::append()`。在这个函数中，如果当前缓冲（[`currentBuffer_`](../muduo/base/AsyncLogging.cc#37)）剩余的空间足够大，则会直接把日志消息拷贝（追加）到[当前缓冲中](../muduo/base/AsyncLogging.cc#39)，这是最常见的情况。这里拷贝一条日志消息并不会带来多大开销（p.120）。前后端代码的其余部分没有拷贝，而是简单的指针交换。\n",
    "\n",
    "否则，说明当前缓冲已经写满，就把它送入（移入）[`buffers_`](../muduo/base/AsyncLogging.cc#43)，并试图把预备好的另一块缓冲（`nextBuffer_`）移用（move）为[当前缓冲](../muduo/base/AsyncLogging.cc#47)，然后追加日志消息并通知（唤醒）后端开始[写入日志数据](../muduo/base/AsyncLogging.cc#53)。以上两种情况在临界区内都没有耗时的操作，运行时间为常数。\n",
    "\n",
    "如果前端写入速度太快，一下子把两块缓冲都用完了，那么只好分配一块新的 [`buffer`](../muduo/base/AsyncLogging.cc#51)，作为当前缓冲，这是极少发生的情况。\n",
    "\n",
    "再来看接收方（后端）实现，这里只给出了[最关键的临界区内的代码](../muduo/base/AsyncLogging.cc#75)，其他琐事请见源文件。\n",
    "\n",
    "首先准备好两块空闲的 buffer，以备在[临界区内交换](../muduo/base/AsyncLogging.cc#63)。在临界区内，[等待条件触发](../muduo/base/AsyncLogging.cc#77)，这里的条件有两个：其一是超时，其二是前端写满了一个或多个 buffer。注意这里是非常规的 condition variable 用法，它没有使用 `while` 循环，而且等待时间有上限。\n",
    "\n",
    "当“条件”满足时，先将当前缓冲（`currentBuffer_`）移入 [`buffers_`](../muduo/base/AsyncLogging.cc#81)，并立刻将空闲的 `newBuffer1` [移为当前缓冲](../muduo/base/AsyncLogging.cc#82)。注意这整段代码位于临界区之内，因此不会有任何 race condition。接下来将 `buffers_` 与 `buffersToWrite` [交换](../muduo/base/AsyncLogging.cc#83)，后面的代码可以在临界区之外安全地访问 `buffersToWrite`，将其中的[日志数据写入文件](../muduo/base/AsyncLogging.cc#88)。临界区里最后干的一件事情是用 [`newBuffer2` 替换 `nextBuffer_`](../muduo/base/AsyncLogging.cc#86)，这样前端始终有一个预备 buffer 可供调配。`nextBuffer_` 可以减少前端临界区分配内存的概率，缩短前端临界区长度。注意到后端临界区内也没有耗时的操作，运行时间为常数。\n",
    "\n",
    "[将 `buffersToWrite` 内的 buffer 重新填充 `newBuffer1` 和 `newBuffer2`](../muduo/base/AsyncLogging.cc#88)，这样下一次执行的时候还有两个空闲 buffer 可用于替换前端的当前缓冲和预备缓冲。最后，这四个缓冲在程序启动的时候会全部填充为 `0`，这样可以避免程序热身时 page fault 引发性能不稳定。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## 运行图示\n",
    "\n",
    "以下再用图表展示前端和后端的具体交互情况。一开始先分配好四个缓冲区A、B、C、D，前端和后端各持有其中两个。前端和后端各有一个缓冲区数组，初始时都是空的。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "**第一种情况**是前端写日志的频度不高，后端3秒超时后将“当前缓冲`current-Buffer_`”写入文件，见图5-1（图中变量名为简写，下同）​。\n",
    "\n",
    "<img src=\"./images/5.1.png\" alt=\"5.1\" style=\"zoom:50%;\" />\n",
    "\n",
    "在第2.9秒的时候，`currentBuffer_`使用了80%，在第3秒的时候后端线程醒过来，[先把`currentBuffer_`送入`buffers_`](../muduo/base/AsyncLogging.cc#81)，[再把`newBuffer1`移用为`currentBuffer_`](../muduo/base/AsyncLogging.cc#82)。随后第3+秒，[交换`buffers_`和`buffersToWrite`](../muduo/base/AsyncLogging.cc#83)，离开临界区，后端开始将buffer A写入文件。写完（write done）之后再把`newBuffer1`重新填上，等待下一次`cond_.waitForSeconds()`返回。\n",
    "\n",
    "后面在画图时将有所简化，不再画出`buffers_`和`buffersToWrite`交换的步骤。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "**第二种情况**，在3秒超时之前已经写满了当前缓冲，于是唤醒后端线程开始写入文件，见图5-2。\n",
    "\n",
    "<img src=\"./images/5.2.png\" alt=\"5.2\" style=\"zoom:50%;\" />\n",
    "\n",
    "在第1.5秒的时候，`currentBuffer_`使用了80%；第1.8秒，`currentBuffer_`写满，[于是将当前缓冲送入`buffers_`](../muduo/base/AsyncLogging.cc#43)，[并将`nextBuffer_`移用为当前缓冲](../muduo/base/AsyncLogging.cc#47)，然后唤醒后端线程开始写入。当后端线程唤醒之后（第1.8+秒），[先将`currentBuffer_`送入`buffers_`](../muduo/base/AsyncLogging.cc#81)，[再把`newBuffer1`移用为`currentBuffer_`](../muduo/base/AsyncLogging.cc#82)，然后[交换`buffers_`和`buffersToWrite`](../muduo/base/AsyncLogging.cc#83)，最后[用`newBuffer2`替换`nextBuffer_`](../muduo/base/AsyncLogging.cc#86)（L68～L71），即保证前端有两个空缓冲可用。离开临界区之后，将`buffersToWrite`中的缓冲区A和B写入文件，写完之后重新填充`newBuffer1`和`newBuffer2`，完成一次循环。\n",
    "\n",
    "上面这两种情况都是最常见的，再来看看前端需要分配新buffer的两种情况。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "**第三种情况**，前端在短时间内密集写入日志消息，用完了两个缓冲，并重新分配了一块新的缓冲，见图5-3。\n",
    "\n",
    "<img src=\"./images/5.3.png\" alt=\"5.3\" style=\"zoom:50%;\" />\n",
    "\n",
    "在第 1.8 秒的时候，缓冲 A 已经写满，缓冲 B 也接近写满，并且已经 `notify()` 了后端线程，但是出于种种原因，后端线程并没有立刻开始工作。到了第 1.9 秒，缓冲 B 也已经写满，前端线程新分配了缓冲 E。到了第 1.8+ 秒，后端线程终于获得控制权，将 C、D 两块缓冲交给前端，并开始将 A、B、E 依次写入文件。一段时间之后，完成写入操作，用 A、B 重新填充那两块空闲缓冲。注意这里有意用 A 和 B 来填充 `newBuffer1/2`，而释放了缓冲 E，这是因为使用 A 和 B 不会造成 page fault。\n",
    "\n",
    "- 思考题：阅读代码并回答，缓冲 E 是何时在哪个线程释放的？"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "**第四种情况**，文件写入速度较慢，导致前端耗尽了两个缓冲，并分配了新缓冲，见图 5-4。\n",
    "\n",
    "<img src=\"./images/5.4.png\" alt=\"5.4\" style=\"zoom:50%;\" />\n",
    "\n",
    "前 1.8+ 秒的场景和前面“第二种情况”相同，前端写满了一个缓冲，唤醒后端线程开始写入文件。之后，后端花了较长时间（大半秒）才将数据写完。这期间前端又用完了两个缓冲，并分配了一个新的缓冲，这期间前端的 `notify()` 已经丢失。当后端写完（write done）后，发现 [`buffers_` 不为空](../muduo/base/AsyncLogging.cc#77)（L61），立刻进入下一循环。即替换前端的两个缓冲，并开始一次写入 C、D、E。假定前端在此期间产生的日志较少，请读者补全后续的情况。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## 改进措施\n",
    "\n",
    "前面我们一共准备了四块缓冲，应该足以应付日常的需求。如果需要进一步增加 buffer 数目，可以改用下面的数据结构。\n",
    "\n",
    "```cpp\n",
    "BufferPtr     currentBuffer_;  // 当前缓冲\n",
    "BufferVector  emptyBuffers_;   // 空闲缓冲\n",
    "BufferVector  fullBuffers_;    // 已写满的缓冲\n",
    "```\n",
    "\n",
    "初始化时在 emptyBuffers_ 中放入足够多空闲 buffer，这样前端几乎不会遇到需要在临界区内新分配 buffer 的情况，这是一种空间换时间的做法。为了避免短时突发写大量日志造成新分配的 buffer 占用过多内存，后端代码应该保证 `emptyBuffers_` 和 `fullBuffers_` 的长度之和不超过某个定值。buffer 在前端和后端之间流动，形成一个循环，如图 5-5 所示。\n",
    "\n",
    "<img src=\"./images/5.5.png\" alt=\"5.5\" style=\"zoom:50%;\" />\n",
    "\n",
    "以上改进留作练习。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## 如果日志消息堆积怎么办\n",
    "\n",
    "万一前端陷入死循环，拼命发送日志消息，超过后端的处理（输出）能力，会导致什么后果？对于同步日志来说，这不是问题，因为阻塞 IO 自然限制了前端的写入速度，起到了节流阀（throttling）的作用。但是对于异步日志来说，这就是典型的生产速度高于消费速度问题，会造成数据在内存中堆积，严重时引发性能问题（可用内存不足）或程序崩溃（分配内存失败）。\n",
    "\n",
    "muduo 日志库处理日志堆积的方法很简单：直接丢掉多余的日志 buffer，以腾出内存，见 [`muduo/base/AsyncLogging.cc`](../muduo/base/AsyncLogging.cc#L92) 第 87～96 行代码。这样可以防止日志库本身引起程序故障，是一种自我保护措施。将来或许可以加上网络报警功能，通知人工介入，以尽快修复故障。"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# 5.4 其他方案\n",
    "\n",
    "当然在前端和后端之间高效传递日志消息的办法不止这一种，比方说使用常规的`muduo::BlockingQueue<std::string>`或`muduo::BoundedBlockingQueue<std::string>`在前后端之间传递日志消息，其中每个std::string是一条消息。这种做法每条日志消息都要分配内存，特别是在前端线程分配的内存要由后端线程释放，因此对malloc的实现要求较高，需要针对多线程特别优化。另外，如果用这种方案，那么需要修改LogStream的Buffer，使之直接将日志写到std::string中，可节省一次内存拷贝。\n",
    "\n",
    "相比前面展示的直接拷贝日志消息的做法，这个传递指针的方案似乎会更高效，但是据我[测试](../recipes/logging/AsyncLogging_test.cc)，直接拷贝日志数据的做法比传递指针快3倍（在每条日志消息不大于4kB的时候），估计是内存分配的开销所致。因此muduo日志库只提供了§ 5.3介绍的这一种异步日志机制。这再次说明“性能”不能凭感觉说了算，一定要有典型场景的测试数据作为支撑。\n",
    "\n",
    "\n",
    "muduo现在的异步日志实现用了一个全局锁。尽管临界区很小，但是如果线程数目较多，锁争用(lock contention)也可能影响性能。一种解决办法是像Java的`ConcurrentHashMap`那样用多个桶子(bucket)，前端写日志的时候再按线程id哈希到不同的bucket中，以减少contention。这种方案的后端实现较为复杂，有兴趣的读者可以试一试。\n",
    "\n",
    "为了简化实现，目前muduo日志库只允许指定日志文件的名字，不允许指定其路径。日志库会把日志文件写到当前路径，因此可以在启动脚本（shell脚本）里改变当前路径，以达到相同的目的。Linux默认会把core dump写到当前目录，而且文件名是固定的core。为了不让新的core dump文件冲掉旧的，我们可以通过sysctl设置kernel.core_pattern参数（也可以修改`/proc/sys/kernel/core_pattern`），让每次core dump都产生不同的文件。例如设为`%e.%t.%p.%u.core`，其中各个参数的意义见man 5 core。另外也可以使用Apport来收集有用的诊断信息，见https://wiki.ubuntu.com/Apport。"
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "C++17",
   "language": "C++17",
   "name": "xcpp17"
  },
  "language_info": {
   "codemirror_mode": "text/x-c++src",
   "file_extension": ".cpp",
   "mimetype": "text/x-c++src",
   "name": "C++17",
   "version": "17"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 2
}
